feat(runtime): debug print in host function call #5018

ailisp · 2021-10-15T06:48:29Z

Test Plan

cargo build -p neard
target/debug/neard --verbose=host-function run

In another terminal:

export NEAR_ENV=local
near deploy --accountId test.near --wasmFile runtime/near-test-contracts/res/simple_state.wasm
near call test.near set_status --accountId test.near '{"message":"hello"}'

In neard window, will see:

...
Oct 15 14:45:06.384 DEBUG gas: host-function: enter
Oct 15 14:45:06.384 DEBUG gas: host-function: close time.busy=63.8µs time.idle=17.7µs
Oct 15 14:45:06.384 DEBUG log_utf8: host-function: enter
Oct 15 14:45:06.384 DEBUG log_utf8: host-function: close time.busy=114µs time.idle=11.7µs

matklad · 2021-10-18T13:09:30Z

@nikurt as the official "king of logging" ( :) ), could you take a look at these log statements? We'll be emitting an event for every host function call, which might be pretty chatty.

nikurt · 2021-10-19T14:38:37Z

Seems to be a useful kind of logging.
If it proves to be too chatty, we can disable it. For example, nearup currently disables debug logging for actix.

This reverts commit f6fb565.

mina86 · 2021-10-21T23:01:43Z

RUST_LOG=host-function=info for those wondering how to disable it.

) This reverts commit f6fb565. #5018 caused too many logs on entering `gas` host function due to how our gas metering works and it slows down neard significantly ``` Oct 21 22:48:11 mainnet-canary0 sh[748906]: Oct 21 22:48:11.557 DEBUG Process block{#50773946}:process_state_update:Runtime::apply:Runtime::process_receipt:run_vm{vm_kind=Wasmer0}:run_wasmer:run_method:run_method/call:gas: host-function: close time.busy=5.97µs time.idle=631ns Oct 21 22:48:11 mainnet-canary0 sh[748906]: Oct 21 22:48:11.557 DEBUG Process block{#50773946}:process_state_update:Runtime::apply:Runtime::process_receipt:run_vm{vm_kind=Wasmer0}:run_wasmer:run_method:run_method/call:gas: host-function: enter Oct 21 22:48:11 mainnet-canary0 sh[748906]: Oct 21 22:48:11.557 DEBUG Process block{#50773946}:process_state_update:Runtime::apply:Runtime::process_receipt:run_vm{vm_kind=Wasmer0}:run_wasmer:run_method:run_method/call:gas: host-function: close time.busy=6.36µs time.idle=593ns Oct 21 22:48:11 mainnet-canary0 sh[748906]: Oct 21 22:48:11.557 DEBUG Process block{#50773946}:process_state_update:Runtime::apply:Runtime::process_receipt:run_vm{vm_kind=Wasmer0}:run_wasmer:run_method:run_method/call:gas: host-function: enter Oct 21 22:48:11 mainnet-canary0 sh[748906]: Oct 21 22:48:11.557 DEBUG Process block{#50773946}:process_state_update:Runtime::apply:Runtime::process_receipt:run_vm{vm_kind=Wasmer0}:run_wasmer:run_method:run_method/call:gas: host-function: close time.busy=5.29µs time.idle=507ns Oct 21 22:48:11 mainnet-canary0 sh[748906]: Oct 21 22:48:11.561 DEBUG Process block{#50773946}:process_state_update:Runtime::apply:Runtime::process_receipt:run_vm{vm_kind=Wasmer0}:run_wasmer:run_method:run_method/call:gas: host-function: enter Oct 21 22:48:11 mainnet-canary0 sh[748906]: Oct 21 22:48:11.561 DEBUG Process block{#50773946}:process_state_update:Runtime::apply:Runtime::process_receipt:run_vm{vm_kind=Wasmer0}:run_wasmer:run_method:run_method/call:gas: host-function: close time.busy=101µs time.idle=1.70µs Oct 21 22:48:11 mainnet-canary0 sh[748906]: Oct 21 22:48:11.561 DEBUG Process block{#50773946}:process_state_update:Runtime::apply:Runtime::process_receipt:run_vm{vm_kind=Wasmer0}:run_wasmer:run_method:run_method/call:gas: host-function: enter Oct 21 22:48:11 mainnet-canary0 sh[748906]: Oct 21 22:48:11.561 DEBUG Process block{#50773946}:process_state_update:Runtime::apply:Runtime::process_receipt:run_vm{vm_kind=Wasmer0}:run_wasmer:run_method:run_method/call:gas: host-function: close time.busy=6.33µs time.idle=735ns Oct 21 22:48:11 mainnet-canary0 sh[748906]: Oct 21 22:48:11.561 DEBUG Process block{#50773946}:process_state_update:Runtime::apply:Runtime::process_receipt:run_vm{vm_kind=Wasmer0}:run_wasmer:run_method:run_method/call:gas: host-function: enter ``` even when there is very little load ``` Oct 21 22:48:41 mainnet-canary0 sh[748906]: Oct 21 22:48:41.724 INFO stats: #50773947 Downloading blocks 99.99% (3248) 13/13/40 peers ⬇ 62.0kiB/s ⬆ 10.6kiB/s 0.05 bps 1.26 Tgas/s CPU: 32%, Mem: 808.2 MiB Oct 21 22:48:56 mainnet-canary0 sh[748906]: Oct 21 22:48:56.188 INFO stats: #50773948 Downloading blocks 99.99% (3290) 13/13/40 peers ⬇ 65.8kiB/s ⬆ 11.0kiB/s 0.07 bps 859.43 Ggas/s CPU: 32%, Mem: 811.6 MiB ``` This caused canary nodes to be broken

@mina86

This fix the problem in #5062 by not logging gas function call. Logging `gas` was a intention choice because i thought it would be helpful to stat its use but betanet deployment has shown it slowdown the node significantly. Test Plan ------------ same as #5018, this time the output doesn't have `gas`: ``` Oct 25 16:55:57.767 INFO stats: Server listening at ed25519:[email protected]:24567 Oct 25 16:56:01.702 DEBUG input: host-function: enter Oct 25 16:56:01.702 DEBUG input: host-function: close time.busy=225µs time.idle=29.7µs Oct 25 16:56:01.702 DEBUG register_len: host-function: enter Oct 25 16:56:01.702 DEBUG register_len: host-function: close time.busy=118µs time.idle=20.2µs Oct 25 16:56:01.702 DEBUG read_register: host-function: enter Oct 25 16:56:01.702 DEBUG read_register: host-function: close time.busy=117µs time.idle=28.8µs Oct 25 16:56:01.703 DEBUG storage_read: host-function: enter Oct 25 16:56:01.703 DEBUG storage_read: host-function: close time.busy=330µs time.idle=12.9µs Oct 25 16:56:01.703 DEBUG register_len: host-function: enter Oct 25 16:56:01.703 DEBUG register_len: host-function: close time.busy=60.5µs time.idle=11.1µs Oct 25 16:56:01.703 DEBUG read_register: host-function: enter Oct 25 16:56:01.703 DEBUG read_register: host-function: close time.busy=72.8µs time.idle=11.1µs Oct 25 16:56:01.704 DEBUG signer_account_id: host-function: enter Oct 25 16:56:01.704 DEBUG signer_account_id: host-function: close time.busy=66.7µs time.idle=11.5µs Oct 25 16:56:01.704 DEBUG register_len: host-function: enter Oct 25 16:56:01.704 DEBUG register_len: host-function: close time.busy=61.3µs time.idle=10.9µs Oct 25 16:56:01.704 DEBUG read_register: host-function: enter Oct 25 16:56:01.704 DEBUG read_register: host-function: close time.busy=72.0µs time.idle=13.8µs Oct 25 16:56:01.704 DEBUG log_utf8: host-function: enter Oct 25 16:56:01.704 DEBUG log_utf8: host-function: close time.busy=74.5µs time.idle=11.5µs Oct 25 16:56:01.704 DEBUG storage_write: host-function: enter Oct 25 16:56:01.704 DEBUG storage_write: host-function: close time.busy=190µs time.idle=12.2µs Oct 25 16:56:07.820 INFO stats: # 3339 332KuomX4nwiREdZwRLA63uekeWLnfszv6UtGctn8Tgf V/1 0/0/40 peers ⬇ 0 B/s ⬆ 0 B/s 1.60 bps 543.20 Ggas/s CPU: 0%, Mem: 0 B ``` Also @mina86 is there a way to test performance as betanet node before merge it to master?

@mina86

This fix the problem in #5062 by not logging gas function call. Logging `gas` was a intention choice because i thought it would be helpful to stat its use but betanet deployment has shown it slowdown the node significantly. Test Plan ------------ same as #5018, this time the output doesn't have `gas`: ``` Oct 25 16:55:57.767 INFO stats: Server listening at ed25519:[email protected]:24567 Oct 25 16:56:01.702 DEBUG input: host-function: enter Oct 25 16:56:01.702 DEBUG input: host-function: close time.busy=225µs time.idle=29.7µs Oct 25 16:56:01.702 DEBUG register_len: host-function: enter Oct 25 16:56:01.702 DEBUG register_len: host-function: close time.busy=118µs time.idle=20.2µs Oct 25 16:56:01.702 DEBUG read_register: host-function: enter Oct 25 16:56:01.702 DEBUG read_register: host-function: close time.busy=117µs time.idle=28.8µs Oct 25 16:56:01.703 DEBUG storage_read: host-function: enter Oct 25 16:56:01.703 DEBUG storage_read: host-function: close time.busy=330µs time.idle=12.9µs Oct 25 16:56:01.703 DEBUG register_len: host-function: enter Oct 25 16:56:01.703 DEBUG register_len: host-function: close time.busy=60.5µs time.idle=11.1µs Oct 25 16:56:01.703 DEBUG read_register: host-function: enter Oct 25 16:56:01.703 DEBUG read_register: host-function: close time.busy=72.8µs time.idle=11.1µs Oct 25 16:56:01.704 DEBUG signer_account_id: host-function: enter Oct 25 16:56:01.704 DEBUG signer_account_id: host-function: close time.busy=66.7µs time.idle=11.5µs Oct 25 16:56:01.704 DEBUG register_len: host-function: enter Oct 25 16:56:01.704 DEBUG register_len: host-function: close time.busy=61.3µs time.idle=10.9µs Oct 25 16:56:01.704 DEBUG read_register: host-function: enter Oct 25 16:56:01.704 DEBUG read_register: host-function: close time.busy=72.0µs time.idle=13.8µs Oct 25 16:56:01.704 DEBUG log_utf8: host-function: enter Oct 25 16:56:01.704 DEBUG log_utf8: host-function: close time.busy=74.5µs time.idle=11.5µs Oct 25 16:56:01.704 DEBUG storage_write: host-function: enter Oct 25 16:56:01.704 DEBUG storage_write: host-function: close time.busy=190µs time.idle=12.2µs Oct 25 16:56:07.820 INFO stats: # 3339 332KuomX4nwiREdZwRLA63uekeWLnfszv6UtGctn8Tgf V/1 0/0/40 peers ⬇ 0 B/s ⬆ 0 B/s 1.60 bps 543.20 Ggas/s CPU: 0%, Mem: 0 B ``` Also @mina86 is there a way to test performance as betanet node before merge it to master?

@mina86

This fix the problem in #5062 by not logging gas function call. Logging `gas` was a intention choice because i thought it would be helpful to stat its use but betanet deployment has shown it slowdown the node significantly. Test Plan ------------ same as #5018, this time the output doesn't have `gas`: ``` Oct 25 16:55:57.767 INFO stats: Server listening at ed25519:[email protected]:24567 Oct 25 16:56:01.702 DEBUG input: host-function: enter Oct 25 16:56:01.702 DEBUG input: host-function: close time.busy=225µs time.idle=29.7µs Oct 25 16:56:01.702 DEBUG register_len: host-function: enter Oct 25 16:56:01.702 DEBUG register_len: host-function: close time.busy=118µs time.idle=20.2µs Oct 25 16:56:01.702 DEBUG read_register: host-function: enter Oct 25 16:56:01.702 DEBUG read_register: host-function: close time.busy=117µs time.idle=28.8µs Oct 25 16:56:01.703 DEBUG storage_read: host-function: enter Oct 25 16:56:01.703 DEBUG storage_read: host-function: close time.busy=330µs time.idle=12.9µs Oct 25 16:56:01.703 DEBUG register_len: host-function: enter Oct 25 16:56:01.703 DEBUG register_len: host-function: close time.busy=60.5µs time.idle=11.1µs Oct 25 16:56:01.703 DEBUG read_register: host-function: enter Oct 25 16:56:01.703 DEBUG read_register: host-function: close time.busy=72.8µs time.idle=11.1µs Oct 25 16:56:01.704 DEBUG signer_account_id: host-function: enter Oct 25 16:56:01.704 DEBUG signer_account_id: host-function: close time.busy=66.7µs time.idle=11.5µs Oct 25 16:56:01.704 DEBUG register_len: host-function: enter Oct 25 16:56:01.704 DEBUG register_len: host-function: close time.busy=61.3µs time.idle=10.9µs Oct 25 16:56:01.704 DEBUG read_register: host-function: enter Oct 25 16:56:01.704 DEBUG read_register: host-function: close time.busy=72.0µs time.idle=13.8µs Oct 25 16:56:01.704 DEBUG log_utf8: host-function: enter Oct 25 16:56:01.704 DEBUG log_utf8: host-function: close time.busy=74.5µs time.idle=11.5µs Oct 25 16:56:01.704 DEBUG storage_write: host-function: enter Oct 25 16:56:01.704 DEBUG storage_write: host-function: close time.busy=190µs time.idle=12.2µs Oct 25 16:56:07.820 INFO stats: # 3339 332KuomX4nwiREdZwRLA63uekeWLnfszv6UtGctn8Tgf V/1 0/0/40 peers ⬇ 0 B/s ⬆ 0 B/s 1.60 bps 543.20 Ggas/s CPU: 0%, Mem: 0 B ``` Also @mina86 is there a way to test performance as betanet node before merge it to master?

ailisp added 2 commits October 15, 2021 12:46

feat(runtime): debug print in host function call

8b5081a

use - instead of space

4805fe6

ailisp requested review from matklad and olonho as code owners October 15, 2021 06:48

matklad requested a review from nikurt October 18, 2021 13:09

matklad approved these changes Oct 18, 2021

View reviewed changes

nikurt approved these changes Oct 19, 2021

View reviewed changes

Merge branch 'master' into debug-print-host-func

cb77bb1

ailisp added the S-automerge label Oct 20, 2021

near-bulldozer bot merged commit f6fb565 into master Oct 20, 2021

near-bulldozer bot deleted the debug-print-host-func branch October 20, 2021 02:26

bowenwang1996 added a commit that referenced this pull request Oct 21, 2021

Revert "feat(runtime): debug print in host function call (#5018)"

585d7a9

This reverts commit f6fb565.

bowenwang1996 mentioned this pull request Oct 21, 2021

Revert "feat(runtime): debug print in host function call (#5018)" #5062

Merged

ailisp mentioned this pull request Oct 25, 2021

feat(runtime): debug log host function call except gas #5076

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat(runtime): debug print in host function call #5018

feat(runtime): debug print in host function call #5018

ailisp commented Oct 15, 2021

matklad commented Oct 18, 2021

nikurt commented Oct 19, 2021

mina86 commented Oct 21, 2021

feat(runtime): debug print in host function call #5018

feat(runtime): debug print in host function call #5018

Conversation

ailisp commented Oct 15, 2021

Test Plan

matklad commented Oct 18, 2021

nikurt commented Oct 19, 2021

mina86 commented Oct 21, 2021